audio logging and diagnostics with structlog by jquast · Pull Request #47 · vxgmichel/gambatte-terminal

jquast · 2026-07-23T18:01:26Z

Replace the TODO stubs for underrun/overrun logging and add per-frame audio telemetry via structlog.

Add --logfile / --loglevel / --logfmt on all entry points (local, SSH, telnet), this is copied from telnetlib3. This is tricky because we really shouldn't log anything when run locally unless --logfile is also used .. so I have changed loglevel to default to critical for local execution, and info for ssh/telnet.

- Add GAMBATERM_AUDIO_LOG and GAMBATERM_AUDIO_CSV to report statistics, replacing some 'TODO' items about logging under and overruns. - Adds common 'fill_fraction' property, to determine - Changed to a batch variable-length emulator audio in send(). runFor() may return only a few hundred samples at video-frame boundaries; feeding those directly to the resampler can starve the ring buffer, instead, accumulate until the batch is large enough prevents this. In practicality, an underrun only occurs when the system is under load, I have only induced a starved ring buffer by using too much cpu by encoding kitty graphics in render(). I plan to address this by "banding", but I think this fix can be helpful for lower end computers or when the system is under load?

Prevent fill_fraction from returning a negative value if read_counter ever exceeds write_counter (should never happen, but this is a cheap safety net).

vxgmichel · 2026-07-24T09:14:09Z

+        # Accumulate input to batch variable-length emulator frames into consistent chunks for the
+        # resampler.  The emulator's runFor() may produce anywhere from a few hundred to tens of
+        # thousands of samples per call; tiny batches could otherwise starve the ring buffer when
+        # under load.


When I introduced the circular buffer, I had in mind that variable-length audio batches would not be a problem since I made sure that the core loop itself is synchronized with the number of produced audio samples:

gambatte-terminal/gambaterm/run.py

Lines 201 to 209 in f6fbf74

# Timing sync

increment = samples / console.TICKS_IN_FRAME

deadline = start + increment / fps

current = time.time()

if current < deadline - 1e-3:

time.sleep(deadline - current)

# Use deadline as new reference to prevent shifting

shifting.append(time.time() - deadline)

start = deadline

So in theory, the producer (i.e gambatte) and the consumer (miniaudio) should move at the exact same rate. The reason why they drift appart is because the producer uses the cpu clock, and the consumer the audio clock. So the job of the PI controller is to detect this slow drift and tune the resample rate to compensate for it. Since the drift is slow, monitoring a rolling average of the fill ratio is a good way to detect and adapt to the drift.

So as far as I can tell, tiny audio batches should not starve the ring buffer since they should be produced faster to compensate (unless the producing of the video frames at a faster rates slows down the core loop, although this should already be accounted for)

Do you think my analysis is correct? Did I miss something?

I can only induce a starved audio buffer by spending too much CPU in rendering, the text mode blitter doesn't consume enough CPU to show the effect. In any case, I will change the render logic there instead, from "always render at least one partial graphics frame", to "skip rendering this frame all together when fill_fraction is low, to allow subsequent frames to fill it back up again before I take too much CPU time rendering it"

I will change the render logic there instead, from "always render at least one partial graphics frame", to "skip rendering this frame all together when fill_fraction is low

I already implemented some logic to detect when the main loop can't keep up with the clock, and skip rendering+outputting the video frame if that's the case:

gambatte-terminal/gambaterm/run.py

Lines 207 to 209 in f6fbf74

# Use deadline as new reference to prevent shifting

shifting.append(time.time() - deadline)

start = deadline

gambatte-terminal/gambaterm/run.py

Lines 142 to 150 in f6fbf74

# Detect if a shift is currently happening

shift = shifting and shifting[-1] > 1 / fps

# Render a new frame only if:

# - it is the right time according to frame_advance

# - a new frame is available from the emulator

# - the screen is ready for a new frame (either CPR sync is disabled, or enabled and we received the CPR response)

# - we are not currently shifting (to prevent flooding the terminal with new frames when the rendering is too slow)

if i % frame_advance == 0 and new_frame and screen_ready and not shift:

It's too bad that it's not enough to keep the audio circular buffer half-full. There are other solutions we can try in order to fix this:

more agressive shifting detection: shifting[-1] > 1 / fps / 2 (or more)

increase the audio_delay_in_frames to 4 or 5, this should give the buffer more time to adapt to sporadic heavy video frames

vxgmichel · 2026-07-24T09:16:18Z

+    logging.basicConfig(**_cfg)
+    logging.getLogger().setLevel(lvl)
+    logging.getLogger(name).setLevel(lvl)
+    return logging.getLogger(name)


I added structlog to the project dependencies in my last PR (#46):
7cc93e0

Maybe you'll find it easier to work with :)

Oh right, I will wire it there, I will have to look at structlog to see what feature is used or useful instead of standard logging

vxgmichel · 2026-07-27T18:24:43Z

This is tricky because we really shouldn't log anything when run locally unless --logfile is also used .. so I have changed loglevel to default to critical for local execution, and info for ssh/telnet.

Can't we simply force a logfile and never log to the console when running locally? Maybe we could make this directory cross-platform and put the log file in there, overwriting it on each run?

gambatte-terminal/gambaterm/ssh.py

Lines 415 to 417 in f6fbf74

    
           gambaterm_config_dir = Path( 
        
               os.environ.get("GAMBATERM_CONFIG_DIR", "~/.config/gambaterm") 
        
           ).expanduser()

jquast added 4 commits July 15, 2026 13:35

Defensive max(0.0, ...) guard in fill_fraction

aa702d6

Prevent fill_fraction from returning a negative value if read_counter ever exceeds write_counter (should never happen, but this is a cheap safety net).

use standard logging interface, only

8e675ae

mypy ..

93b811a

jquast force-pushed the jq/audio-fixes branch from b2a531a to 93b811a Compare July 23, 2026 18:13

jquast added 2 commits July 23, 2026 14:19

upgrade mypy for its false problems

c6a92c4

don't double log, per-frame stats go to CSV, only

c93b595

vxgmichel reviewed Jul 24, 2026

View reviewed changes

remove batching and use structlog

98f1e72

jquast force-pushed the jq/audio-fixes branch from 5706f6b to 98f1e72 Compare July 24, 2026 13:58

jquast changed the title ~~Variable-length audio buffering and logging~~ audio logging and diagnostics with structlog Jul 24, 2026

local CLI defaults to 'critical' log level

a1bf4ce

Navigation Menu

audio logging and diagnostics with structlog - #47

audio logging and diagnostics with structlog#47
jquast wants to merge 8 commits into
vxgmichel:mainfrom
jquast:jq/audio-fixes

jquast commented Jul 23, 2026 •

edited

Loading

Uh oh!

vxgmichel Jul 24, 2026 •

edited

Loading

Uh oh!

jquast Jul 24, 2026

Uh oh!

vxgmichel Jul 27, 2026

Uh oh!

vxgmichel Jul 24, 2026 •

edited

Loading

Uh oh!

jquast Jul 24, 2026

Uh oh!

vxgmichel commented Jul 27, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

	# Timing sync
	increment = samples / console.TICKS_IN_FRAME
	deadline = start + increment / fps
	current = time.time()
	if current < deadline - 1e-3:
	time.sleep(deadline - current)
	# Use deadline as new reference to prevent shifting
	shifting.append(time.time() - deadline)
	start = deadline

	# Detect if a shift is currently happening
	shift = shifting and shifting[-1] > 1 / fps

	# Render a new frame only if:
	# - it is the right time according to frame_advance
	# - a new frame is available from the emulator
	# - the screen is ready for a new frame (either CPR sync is disabled, or enabled and we received the CPR response)
	# - we are not currently shifting (to prevent flooding the terminal with new frames when the rendering is too slow)
	if i % frame_advance == 0 and new_frame and screen_ready and not shift:

Conversation

jquast commented Jul 23, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vxgmichel Jul 24, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jquast Jul 24, 2026

Choose a reason for hiding this comment

Uh oh!

vxgmichel Jul 27, 2026

Choose a reason for hiding this comment

Uh oh!

vxgmichel Jul 24, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jquast Jul 24, 2026

Choose a reason for hiding this comment

Uh oh!

vxgmichel commented Jul 27, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jquast commented Jul 23, 2026 •

edited

Loading

vxgmichel Jul 24, 2026 •

edited

Loading

vxgmichel Jul 24, 2026 •

edited

Loading